Implement optional ring buffer for container logs #28762

cpuguy83 · 2016-11-23T15:20:30Z

This allows the user to set a logging mode to "blocking" (default), or
"non-blocking", which uses the ring buffer as a proxy to the real log
driver.

This allows a container to never be blocked on stdio at the cost of
dropping log messages.

Introduces a new flag to docker run and dockerd, --log-mode, which
takes a value of "blocking", or "non-blocking". I chose not to implement
this as a bool since it is difficult to determine if the mode was set to
false vs just not set... especially difficult when merging the default
daemon config with the container config.

One thing to think about here is logger.Message could be any size, it just depends on how long the log line was... so it could be almost nothing, or it could be several megabytes which could cause problems in just blindly buffering N number of messages in the ring buffer.
We could keep track of this, but this could be tricky and introduces locking into the implementation.

justincormack · 2016-11-23T17:03:21Z

Seems like one reasonable solution. I wonder if the ring buffer should be a fixed size in bytes though (which can be specified). Then this would carry over simply to a compatible interfaces via a pipe, where you could set the pipe buffer size and discard if no space. There are some issues about message boundaries though, you could use datagrams and allow truncation.

LK4D4 · 2016-11-23T17:05:23Z

@cpuguy83 maybe embed it to log-opt?

cpuguy83 · 2016-11-23T17:06:51Z

@cpuguy83 maybe embed it to log-opt?

@LK4D4 The reason I didn't want to do that is log-opt tends to be options for the driver, where as this is changing how docker itself handles logs.

cpuguy83 · 2016-11-23T17:10:39Z

daemon/logger/ring.go

+	default:
+		select {
+		case <-r.ctx.Done():
+		case <-r.queue: // Make room on the queue


May need to add a lock to protect against another log message coming in right after this but before we get a chance to queue below.

I'd better try to implement messages ring buffer as a separate data structure with tests and stuff. Probably that was your plan after design review.

LK4D4 · 2016-11-23T17:21:56Z

I agree with @justincormack about specifying size. However, computing size might be challenging. The number of messages might be okay, too for average use.
Design +1

AkihiroSuda · 2016-11-24T04:25:04Z

Design SGTM 👍

thaJeztah · 2016-11-26T00:19:21Z

One thing to think about here is logger.Message could be any size, it just depends on how long the log line was...

Perhaps silly comment, but https://github.com/docker/docker/pull/22982/files#diff-0e0dba78caf4a57795625b5ce9943c9eR13 introduced a buffer size, i.e., messages longer than that size are split (even if there's no newline); or is that not relevant here?

cpuguy83 · 2016-11-26T00:26:09Z

That's true, there is a max. But I think people want to control the buffer based on size not number of messages.
So I've pushed a new implementation doing just this.

cpuguy83 · 2016-11-26T14:35:19Z

@justincormack Implementing this in github.com/pkg/iotutils.BytesPipe is fairly trivial I think, but wondering what's better, drop random byte slices or full messages.

cpuguy83 · 2016-11-26T14:53:38Z

Although certainly implementing in BytesPipe is significantly faster since we don't need to do any extra allocations, where as each call to Log() as implemented here requires 1 allocation.

I went ahead and added an implementation in BytesPipe just to look at, presented without tests or benchmarks at the moment.

justincormack · 2016-11-26T15:22:03Z

Best to drop full messages I think. They might be JSON or something and truncating would be unhelpful.

…

On 26 Nov 2016 2:35 p.m., "Brian Goff" ***@***.***> wrote: @justincormack <https://github.com/justincormack> Implementing this in github.com/pkg/iotutils.BytesPipe is fairly trivial I think, but wondering what's better, drop random byte slices or full messages. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#28762 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAdcPPpe7Uf5tLMOCojYaCpkvPg0em68ks5rCEOugaJpZM4K6tX6> .

AkihiroSuda · 2016-11-28T04:51:30Z

daemon/logger/ring.go

+// the passed in logger.
+func NewRingLogger(driver Logger, logCtx Context, maxSize int64) Logger {
+	if maxSize < 0 {
+		maxSize = defaultRingMaxSize


nit: personally, I prefer zero-value for indicating the default

Yes, but I wanted to support a 0 size, which would essentially mean store no more than 1 message.

AkihiroSuda · 2016-11-28T04:53:27Z

runconfig/opts/parse.go

 	flags.Var(&copts.loggingOpts, "log-opt", "Log driver options")
+	flags.StringVar(&copts.volumeDriver, "volume-driver", "", "Optional volume driver for the container")


unintended change, perhaps?

Intended, just re-ordered so log-opt is underneath log-driver.

cpuguy83 · 2016-11-28T15:02:49Z

Removed the commit with the bytespipe changes.

LK4D4 · 2016-11-28T15:27:50Z

daemon/logger/awslogs/cloudwatchlogs.go

@@ -176,7 +176,9 @@ func (l *logStream) Log(msg *logger.Message) error {
 	defer l.lock.RUnlock()
 	if !l.closed {
 		// buffer up the data, making sure to copy the Line data
-		l.messages <- logger.CopyMessage(msg)
+		var copy logger.Message
+		copy = *msg


This doesn't clone underlying message([]byte), which was whole point IIRC.

We shouldn't need to clone the message bytes because that won't ever change.
It's the passed in *Message which gets changed by the log copier since it keeps a single message pointer for all messages.

Copier uses parts of its own buffer for Line:
https://github.com/docker/docker/blob/master/daemon/logger/copier.go#L81
And drivers like fluentd can collect messages for later send, so their Line will be overriden by copier.
Also, I believe this was in comment to CopyMessage :D

Oh you're right. I'll bring this back.

LK4D4 · 2016-11-28T15:28:40Z

daemon/logger/ring.go

+package logger
+
+import (
+	"context"


should be net/context

LK4D4 · 2016-11-28T15:58:18Z

Cond based buffer is kinda cool. Will review later today.

This functionality was added in moby/moby#28762. It allows a user to specify what to do in cases when a log message can't be sent, block the container's stdio or drop messages. Also removes an erronious entry about a `nats` log driver, which does not exist. Signed-off-by: Brian Goff <cpuguy83@gmail.com>

glasser · 2017-06-26T18:37:37Z

Based on reading the source, it looks like there's a serious bug here in the journald and syslog drivers. (Haven't managed to verify yet with an actual built version.) In both of those drivers, you call logger.PutMessage(msg) and then afterwards read msg.Source. But PutMessage calls msg.reset() which clears Source. Am I missing something or do the drivers not need to save those values before calling PutMessage?

cpuguy83 · 2017-06-26T18:40:11Z

@glasser PutMessage should only be called after the value has already been copied.

For instance:

line := string(msg.Source)

This copies the value of msg.Source rather than the reference to msg.Source.

glasser · 2017-06-26T18:44:35Z

I agree. But look at this code this PR put into the syslog driver, which remains there to this day:

func (s *syslogger) Log(msg *logger.Message) error {
	line := string(msg.Line)
	logger.PutMessage(msg)
	if msg.Source == "stderr" {
		return s.writer.Err(line)
	}
	return s.writer.Info(line)
}

That sure seems to read from Source after calling PutMessage. Similar code exists in the journald driver.

cpuguy83 · 2017-06-26T18:46:57Z

@glasser Yeah, that looks like an issue!
Do you want to open a PR to fix this?

logger.PutMessage, added in moby#28762 (v17.04.0-ce), clears msg.Source. So journald and syslog were treating stderr messages as if they were stdout. Signed-off-by: David Glasser <glasser@davidglasser.net>

glasser · 2017-06-26T21:38:16Z

@cpuguy83 sure, #33832

…g options. Documentation based on: * implementation and comments of the [Ring Logger](https://github.com/moby/moby/blob/master/daemon/logger/ring.go#L49) * conversation in implementing [PR 28762](moby/moby#28762)

GordonTheTurtle added the status/0-triage label Nov 23, 2016

cpuguy83 added status/1-design-review and removed status/0-triage labels Nov 23, 2016

cpuguy83 mentioned this pull request Nov 23, 2016

Implement plugins for logging drivers #28403

Merged

cpuguy83 force-pushed the logger_ring_buffer branch from 3af168d to 7f18df6 Compare November 23, 2016 15:57

cpuguy83 commented Nov 23, 2016

View reviewed changes

cpuguy83 force-pushed the logger_ring_buffer branch 2 times, most recently from 20366c4 to 52626ee Compare November 25, 2016 23:32

cpuguy83 force-pushed the logger_ring_buffer branch from 52626ee to 7980fcd Compare November 26, 2016 14:39

AkihiroSuda added the rebuild/windowsRS1 label Nov 28, 2016

GordonTheTurtle removed the rebuild/windowsRS1 label Nov 28, 2016

AkihiroSuda reviewed Nov 28, 2016

View reviewed changes

cpuguy83 force-pushed the logger_ring_buffer branch from 8d54153 to 7980fcd Compare November 28, 2016 15:02

LK4D4 added status/2-code-review and removed status/1-design-review labels Nov 28, 2016

LK4D4 suggested changes Nov 28, 2016

View reviewed changes

cpuguy83 force-pushed the logger_ring_buffer branch from 7980fcd to d15b37d Compare November 28, 2016 16:05

cpuguy83 mentioned this pull request Feb 1, 2017

Docker logging blocks and never recovers #22502

Closed

albers mentioned this pull request Feb 2, 2017

Add bash completion for {dockerd,docker run} --log-opt max-buffer-size|mode #30668

Merged

cpuguy83 deleted the logger_ring_buffer branch February 2, 2017 13:30

cpuguy83 mentioned this pull request Feb 2, 2017

Adds details about new non-blocking logging mode docker/docs#1482

Merged

sdurrheimer mentioned this pull request Feb 12, 2017

Add zsh completion for docker log options 'max-buffer-size|mode' #30946

Merged

albers mentioned this pull request Feb 13, 2017

Fix bash completion for --log-opt mode #30980

Merged

glasser mentioned this pull request Jun 26, 2017

Fix stderr logging for journald and syslog #33832

Merged

thaJeztah mentioned this pull request Nov 17, 2017

awslogs drive should not prevent container from starting on failure to connect to AWS CloudWatch Logs endpoint #33803

Closed

skuenzli mentioned this pull request Dec 24, 2017

Document the mode and max-buffer-size log options docker/docs#5613

Merged

This was referenced Jun 17, 2019

Fix stderr logging for journald and syslog projectatomic/docker#345

Merged

Fix stderr logging for journald and syslog projectatomic/docker#346

Merged

danieladams456 mentioned this pull request Nov 25, 2020

Non-blocking default for log drivers? #41714

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Implement optional ring buffer for container logs #28762

Implement optional ring buffer for container logs #28762

cpuguy83 commented Nov 23, 2016

justincormack commented Nov 23, 2016

LK4D4 commented Nov 23, 2016

cpuguy83 commented Nov 23, 2016

cpuguy83 Nov 23, 2016

LK4D4 Nov 23, 2016

LK4D4 commented Nov 23, 2016

AkihiroSuda commented Nov 24, 2016

thaJeztah commented Nov 26, 2016

cpuguy83 commented Nov 26, 2016

cpuguy83 commented Nov 26, 2016

cpuguy83 commented Nov 26, 2016

justincormack commented Nov 26, 2016 via email

AkihiroSuda Nov 28, 2016

cpuguy83 Nov 28, 2016

AkihiroSuda Nov 28, 2016

cpuguy83 Nov 28, 2016

cpuguy83 commented Nov 28, 2016

LK4D4 Nov 28, 2016

cpuguy83 Nov 28, 2016

LK4D4 Nov 28, 2016

cpuguy83 Nov 28, 2016

LK4D4 Nov 28, 2016

LK4D4 commented Nov 28, 2016

glasser commented Jun 26, 2017

cpuguy83 commented Jun 26, 2017

glasser commented Jun 26, 2017

cpuguy83 commented Jun 26, 2017

glasser commented Jun 26, 2017

		flags.Var(&copts.loggingOpts, "log-opt", "Log driver options")
		flags.StringVar(&copts.volumeDriver, "volume-driver", "", "Optional volume driver for the container")

Implement optional ring buffer for container logs #28762

Implement optional ring buffer for container logs #28762

Conversation

cpuguy83 commented Nov 23, 2016

justincormack commented Nov 23, 2016

LK4D4 commented Nov 23, 2016

cpuguy83 commented Nov 23, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

LK4D4 commented Nov 23, 2016

AkihiroSuda commented Nov 24, 2016

thaJeztah commented Nov 26, 2016

cpuguy83 commented Nov 26, 2016

cpuguy83 commented Nov 26, 2016

cpuguy83 commented Nov 26, 2016

justincormack commented Nov 26, 2016 via email

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

cpuguy83 commented Nov 28, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

LK4D4 commented Nov 28, 2016

glasser commented Jun 26, 2017

cpuguy83 commented Jun 26, 2017

glasser commented Jun 26, 2017

cpuguy83 commented Jun 26, 2017

glasser commented Jun 26, 2017